Feature-Request: Timestamp or some other correlationID required

xeno · June 19, 2019, 2:50pm

Used Zammad version: 3.0.0-1560433985.617324d6.bionic
Used Zammad installation source: (source, package, …) ubuntu-package
Operating system: ubuntu 18.04 x64
Browser + version: not relevant

Expected behavior:

migrator reports some correlation data to identify issues

Actual behavior:

migrator fails with timeouts, but hard to find what is the cause for it
output grep cat console.log|grep -E "thread#5:|^[[:blank:]]+from"

thread#5: update Ticket.find_by(id: 35325) thread#5: update Ticket::Article.find_by(id: 3892741) thread#5: loading 20 Ticket starting at 56240... thread#5: POST: https://otrs.example.com/otrs/public.pl?Action=ZammadMigrator thread#5: PARAMS: {:Subaction=>"Export", :Object=>"Ticket", :Limit=>20, :Offset=>56240, :Diff=>0, :Action=>"ZammadMigrator", :Key=>"123456789wert6zuio"} from lib/import/otrs/requester.rb:130:inpost’
from lib/import/otrs/requester.rb:90:in request_json' from lib/import/otrs/requester.rb:77:inrequest_result’
from lib/import/otrs/requester.rb:32:in load' from lib/import/otrs.rb:141:inimport_action’
from lib/import/otrs.rb:135:in imported?' from lib/import/otrs.rb:99:inblock (3 levels) in threaded_import’
from lib/import/otrs.rb:93:in loop' from lib/import/otrs.rb:93:inblock (2 levels) in threaded_import’
thread#5: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>
thread#5: POST: https://otrs.example.com/otrs/public.pl?Action=ZammadMigrator
thread#5: PARAMS: {:Subaction=>“Export”, :Object=>“Ticket”, :Limit=>20, :Offset=>56240, :Diff=>0, :Action=>“ZammadMigrator”, :Key=>“123456789wert6zuio”}
thread#5: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>
thread#5: POST: https://otrs.example.com/otrs/public.pl?Action=ZammadMigrator
thread#5: PARAMS: {:Subaction=>“Export”, :Object=>“Ticket”, :Limit=>20, :Offset=>56240, :Diff=>0, :Action=>“ZammadMigrator”, :Key=>“123456789wert6zuio”}
thread#5: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>
from /opt/zammad/lib/import/otrs/requester.rb:90:in request_json' from /opt/zammad/lib/import/otrs/requester.rb:77:inrequest_result’
from /opt/zammad/lib/import/otrs/requester.rb:32:in load' from /opt/zammad/lib/import/otrs.rb:141:inimport_action’
from /opt/zammad/lib/import/otrs.rb:135:in imported?' from /opt/zammad/lib/import/otrs.rb:99:inblock (3 levels) in threaded_import’
from /opt/zammad/lib/import/otrs.rb:93:in loop' from /opt/zammad/lib/import/otrs.rb:93:inblock (2 levels) in threaded_import’
from /opt/zammad/vendor/bundle/ruby/2.4.0/gems/logging-2.2.2/lib/logging/d`

Steps to reproduce the behavior:

run migration from very old OTRS (install 2005; currently running 5.0.x )

Any ideas how to track down the issue? I am missing any correlation to OTRS to get the corresponding error or message from log from OTRS

MrGeneration · June 21, 2019, 9:07am

Did you install the migration plugin beforehand?
https://docs.zammad.org/en/latest/migration-otrs.html

xeno · June 21, 2019, 10:08am

hey come on
So basic steps are surely done… You see it from the first log message also, that the migration was already running.
So yes, plugin is installed.

Have I not seen some correlationID in the OTRS logs? If so, what is the ID?

MrGeneration · June 21, 2019, 10:09am

Sorry for asking
@thorsteneckel might be a better partner here

xeno · June 24, 2019, 7:05am

I am failing with the migration and since of really to few details and also what time the thread was started it seems not to be solvable.

@thorsteneckel any updates on the correlationID (e.g. a timestamp on requests or even better a uuid on OTRS log and zammad-migrator log) to track down my issues?
Maybe also something of these related issues? Are multiple runs of OTRS migrator possible - maybe with yearly migrate runs? - #3 by xeno

e.g. I am often failing on:

thread#1: loading 20 Ticket starting at 56480...
thread#1: POST: https://otrs.example.com/otrs/public.pl?Action=ZammadMigrator
thread#1: PARAMS: {:Subaction=>"Export", :Object=>"Ticket", :Limit=>20, :Offset=>56480, :Diff=>0, :Action=>"ZammadMigrator", :Key=>"1234567890ßqwertzuiop"}
thread#1: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>
thread#1: POST: https://otrs.example.com/otrs/public.pl?Action=ZammadMigrator
thread#1: PARAMS: {:Subaction=>"Export", :Object=>"Ticket", :Limit=>20, :Offset=>56480, :Diff=>0, :Action=>"ZammadMigrator", :Key=>"1234567890ßqwertzuiop"}
thread#1: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>
thread#1: POST: https://otrs.example.com/otrs/public.pl?Action=ZammadMigrator
thread#1: PARAMS: {:Subaction=>"Export", :Object=>"Ticket", :Limit=>20, :Offset=>56480, :Diff=>0, :Action=>"ZammadMigrator", :Key=>"1234567890ßqwertzuiop"}
thread#1: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>
        from /opt/zammad/lib/import/otrs/requester.rb:90:in "request_json"
        from /opt/zammad/lib/import/otrs/requester.rb:77:in "request_result"
        from /opt/zammad/lib/import/otrs/requester.rb:32:in "load"
        from /opt/zammad/lib/import/otrs.rb:141:in "import_action"
        from /opt/zammad/lib/import/otrs.rb:135:in "imported?"
        from /opt/zammad/lib/import/otrs.rb:99:in "block (3 levels) in threaded_import"
        from /opt/zammad/lib/import/otrs.rb:93:in "loop"
        from /opt/zammad/lib/import/otrs.rb:93:in "block (2 levels) in threaded_import"
        from /opt/zammad/vendor/bundle/ruby/2.4.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in "block in create_with_logging_context"

since I cannot correlate the error with OTRS log I am failing to track down the issue

MrGeneration · June 24, 2019, 10:13am

Thorsten currently is quite busy, please give him sime time.

If you need help NOW and thus need commercial services, please feel free to contact us at sales [at] zammad [dot] com

thorsteneckel · June 24, 2019, 10:23am

Hi @xeno,

I can’t see any remarks about the correlationID in the logs. Can you tell me where it comes from?

What I see in the logs is that your OTRS takes to long to answer that HTTP POST request:

thread#5: PARAMS: {:Subaction=>“Export”, :Object=>“Ticket”, :Limit=>20, :Offset=>56240, :Diff=>0, :Action=>“ZammadMigrator”, :Key=>“123456789wert6zuio”}

It runs into a timeout:

thread#5: ERROR: #<Net::ReadTimeout: Net::ReadTimeout>

These timeouts are usually enough but apparently not in your case. You can go and change these in your local installation by tweaking the following numbers:

github.com

zammad/zammad/blob/96f6d5e0e594dcf779ff73005a937e6c5ea879de/lib/import/otrs/requester.rb#L116-L118


open_timeout:  10,
read_timeout:  120,
total_timeout: 360,

xeno · June 24, 2019, 10:45am

I can’t see any remarks about the correlationID in the logs. Can you tell me where it comes from?

on multi-systems debugging via log you need something to correlate the log messages. The simpliest one is a timestamp in the logs. This is missing in the migrator.
The better one is to have UUIDs on both sides, so you clearly identify errors independently if you have tons of parallel threads on any system.

What I see in the logs is that your OTRS takes to long to answer that HTTP POST request:

thread#5: PARAMS: {:Subaction=>“Export”, :Object=>“Ticket”, :Limit=>20, :Offset=>56240, :Diff=>0, Action=>“ZammadMigrator”, :Key=>“123456789wert6zuio”}

how do you see it from that log message? I have no clue how you identify the issue from this line?

Thank you for the hint. Changed the timeouts by trippeling them. Will report if this will not work.

xeno · July 11, 2019, 9:22am

Just for clearance, I am referencing here the console output and not the production.log of zammad.
Got the hint from @MrGeneration to also check the production.log which I am running now again.
Anyway please add also the timestamp to the console output

xeno · July 11, 2019, 6:20pm

after identifying that production.log is containing similar data as the console output but with timestamps, I could track down that my read_timeout of 120sec is still too small. Increased it now to read_timeout=600 along with total_timeout=1800 and rerunning my migration again.
Maybe it helps now…

system · November 8, 2019, 6:20pm

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.