Uploaded image for project: 'Confluence Data Center'
  1. Confluence Data Center
  2. CONFSERVER-54936

Misleading error during XML import failure references the wrong content

    XMLWordPrintable

Details

    Description

      Problem summary

      An XML export can contain bad data caused by bugs (such as CONFSERVER-38993) which can cause a failure during an import attempt. The Confluence logs do not always report the correct row that is failing the import. In order to find the actual cause of failure, an administrator needs to enable very verbose logging and re-run the import until failure, which can be inconvenient and take many hours depending on size of the dataset.

      Example

      In one instance, the import failed and the logs printed the below:

      2018-01-19 12:37:12,688 ERROR [Long running task: Importing data] [engine.jdbc.spi.SqlExceptionHelper] logExceptions ERROR: value too long for type character varying(255)
       -- url: /longrunningtaskxml.action | referer: http://confluence.example.com/admin/restore-local-file.action | traceId: 37db6afd87d848bd | userName: admin | action: longrunningtaskxml
      
      2018-01-19 12:37:12,818 ERROR [Long running task: Importing data] [confluence.importexport.xmlimport.DefaultImportProcessor] persist Error while saving object: Imported[com.atlassian.confluence.links.OutgoingLink] [Id[id]=12345678, Property[destinationPageTitle]=//jira/browse/EX-12345, Property[lowerDestinationPageTitle]=//jira/browse/ex-12345, Property[destinationSpaceKey]=http, Property[lowerDestinationSpaceKey]=http, Property[sourceContent]=com.atlassian.confluence.pages.Page[Id[id]=4567890], Property[creator]=com.atlassian.confluence.user.ConfluenceUserImpl[Id[key]=8aa3087e452fdd2e01452fde8e551b66], Property[creationDate]=2017-03-23 22:10:32.000, Property[lastModifier]=com.atlassian.confluence.user.ConfluenceUserImpl[Id[key]=8aa3087e452fdd2e01452fde8e551b66], Property[lastModificationDate]=2017-03-23 22:10:32.000]
       -- url: /longrunningtaskxml.action | referer: http://confluence.example.com/admin/restore-local-file.action | traceId: 37db6afd87d848bd | userName: admin | action: longrunningtaskxml
      

      At a glance, it seems that a column's max length in the database was exceeded (more than 255 characters), and the offending content is related to a row in the LINKS table (com.atlassian.confluence.links.OutgoingLink). However, this is completely misleading as we can see that nothing in that record contains close to 255 characters.

      Troubleshooting

      To find the true offending content, one needs to enable detailed SQL logging which is very verbose, and then re-run the migration up to the point of failure: https://confluence.atlassian.com/doc/enabling-detailed-sql-logging-179030.html

      When this is done, we see that the last content Confluence was trying to insert which caused the failure during import was actually something completely different (an an object relating to inline comments in this example):

       2018-01-24 13:38:19,047 DEBUG [Long running task: Importing data] [org.hibernate.SQL] logStatement insert into CONTENTPROPERTIES (PROPERTYNAME, STRINGVAL, LONGVAL, DATEVAL, PROPERTYID) values (?, ?, ?, ?, ?)
      
       2018-01-24 13:38:19,047 TRACE [Long running task: Importing data] [type.descriptor.sql.BasicBinder] bind binding parameter [1] as [VARCHAR] - [inline-original-selection]
       2018-01-24 13:38:19,047 TRACE [Long running task: Importing data] [type.descriptor.sql.BasicBinder] bind binding parameter [2] as [VARCHAR] - [Lorem ipsum dolor sit amet, consectetur adipiscing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exercitation ullamco laboris nisi ut aliquip ex ea commodo consequat. Duis aute irure dolor...]
       2018-01-24 13:38:19,047 TRACE [Long running task: Importing data] [type.descriptor.sql.BasicBinder] bind binding parameter [3] as [BIGINT] - [null]
       2018-01-24 13:38:19,048 TRACE [Long running task: Importing data] [type.descriptor.sql.BasicBinder] bind binding parameter [4] as [TIMESTAMP] - [null]
       2018-01-24 13:38:19,048 TRACE [Long running task: Importing data] [type.descriptor.sql.BasicBinder] bind binding parameter [5] as [BIGINT] - [1234567890]
      

      Additional notes

      This issue may be due to batching processes in the import. The error recorded in the standard logs may be referring to the first entry in the batch which contains the offending row. Ideally, we should be logging the actual offending row instead.

      Attachments

        Issue Links

          Activity

            People

              03cb0c04aa4f Irina Tiapchenko
              rchang Robert Chang
              Votes:
              11 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: